マイクロサービスのアプリケーションログ転送量の抑制と改善

小室啓

2020.04.24

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

はじめに

こんにちは。こむろ＠事業開発部です。あ、今回も改善の話です。新機能開発とかそういった話はありませんのであしからず。

所属している事業開発部では、prismatixというECプラットフォームサービスを開発・運用しております。ECですので、商品の管理、検索、購入や会員管理等の多種多様な機能があり、それぞれのサービスでは日々膨大なアプリケーションログを記録しています。

アプリケーションログは正常動作している時は、あまり必要ではないのですが、いざ何らかの問題が発生した際に、原因究明やデータ復旧には欠かせないデータです。従って保険としてできれば全てを保存しておきたいところです。

しかしながら、このログの保存。機能の数やリクエスト規模にもよりますが、膨大が故に非常にお金がかかります。そして正直なところ大抵は利用されないゴミです。 ^*1

このあたりの話については、Release It! 本番用ソフトウェア製品の設計とデプロイのためにに非常によくまとまっていてオススメです。

現状

現状抱えている課題について以下になります。

全てのマイクロサービスのアプリケーションログをCloudwatch Logsへ集約
- すべてのログレベル。
- INFO, WARN, ERROR（たまにDEBUGも）すべて
そのため Cloudwatch Logs の利用料金が 青天井で爆発

例としてある一つのサービスから約 2GB/Min のログが転送されていました。 ^*2できれば一箇所に全てを集約しておきたいところなのですが、お金は有限です。リソースへ支払うコストと運用コストを天秤にかけて判断する他ありません。

今回は「多少運用のコストは上がってもリソースへ支払うコストを大幅に下げろ」というのが急務になったため、これを3週間程度で実現します。

目標

最低限クリアすべき目標を以下に掲げました。

Cloudwatch の利用料金を大幅に下げること（1/10くらいを目指す）
アプリケーションログが欠落なく全て保存されていること
- これがまた難しい。現状様々な問題から一部抜けてる状態なので、今以上を目指すことになる。
保存しているログを検索するための代替手段を提供する

コストを下げるのは最大の目標なので、これは変わりません。これを実現しないことには、この改善タスクフォースに存在意義がなくなります。

アプリケーションログの保存については、現状ですでに100％でないため、ここは極力の目標になります。現在 Cloudwatch Logsへの転送が多すぎて上限にひっかかり、イベントのピーク時にはすべてのログが記録しきれていないなど、様々な問題が山積している状況です。

現状の姿

現在どのような形でログを転送しているかの簡易図が以下になります。

現在はすべてが fluentd を通して Cloudwatch Logs へ転送されています。

金が飛んでいく。

改善のアプローチ

今回の改善では制限として「インフラ、ミドルウェア（fluentd）の構成変更、設定変更は行わない」というものがありました。

従ってログを生成して送出する元であるアプリケーション側で工夫する必要があります。

こういったアプローチになった背景として、すでに本番稼働中の環境が急務であり、インフラ、ミドルウェアの構成変更を伴う検討、修正が難しいという状況があります。

時間が充分に取れて充分な検証期間、検証項目、本番同等の負荷をかけての試験等が滞りなくできる場合は、インフラ、ミドルウェアの構成から抜本的にアーキテクチャを見直し、あるべき姿を目指した方が健全かもしれません。今回はこういった事情があり、常日頃修正とデプロイを繰り返しているアプリケーション側での対応でできる範囲を模索するという方針になっています。

ログ転送構成 -改-

では上記を踏まえてログの転送構成を変更します。以下簡単なイメージです。

アプリケーションログ（INFO|DEBUG以降）は標準出力に出さず、ファイルに出力。アプリケーション自身がローテーションのタイミングで S3 に直接アップロードを実行します。これにより、標準出力のログが大幅に抑制することができそうです。

しかしこれを実行するには以下を改修する必要があります。

Logback の Appender のログローテーションのタイミングに Hook して S3 へアップロードする方法
終了時にログローテーション実行前の現在書き込んでいる Active なログを S3 へアップロードする方法
異常終了時にロストせずに Active なログを転送する方法

Logback RollingPolicy to store logs in S3

まずはアプリケーションログをアプリケーション自身が S3 へアップロードする方法を模索します。

Logback では RollingFileAppender によってログファイルをアーカイブしてローテーションする機能があります。ここでは特に詳細の説明はしません。この Appender を拡張して S3 へのアップロード機能を追加します。

ばっちり目的に合致したコードが Github にありました。

Github - link-nv/logback-s3-rolling-policy

時間ベースのRollingPolicy, サイズベースのRollingPolicyが定義されており、使い方を見る限り今回の目的に適しているようです。

ただし、Commit履歴を見るとわかるように非常に古いコードです。Logback等のコードに関してはあまり問題ないのですが、AWS周りのコードは色々と古いため改修が必要であることがわかりました。以下が改善が必要なもの。

AWS SDKのVersionが非常に古い
AmazonS3Client を利用している
- 最新の Javadoc を見てわかるように @Deprecated です。
EC2のメタデータを利用して一意なIDを作っている
- 今回はECSで使いたいので、EC2のメタデータだと一意性が担保できない

logback-s3-rolling-policy を改修

元のコードをForkして最低限の修正を施しました（READMEはまだ不完全）

Github - komuro-hiraku/logback-s3-rolling-policy

上記の問題点の修正以外に、Github pages を maven repository として構成するように変更しました。改修内容の詳細についてはまた後日（気力 ~~と時間~~ があれば）記事にします。改修点は以下になります。

AWS SDK Versionの更新
ECSのコンテナメタデータからコンテナIDを取得してIdentifierとするように修正
AmazonS3Client の利用を廃止し別の方法へ変更

網羅すべきパターン

上記でアプリケーションから直接 S3 へアップロードする方法が確立できました。さて、これだけで充分かというとそうではありません。異常終了時のケースは何一つ考慮されていないので、そちらも考えておく必要があります。考えうる網羅すべきパターンはざっくり以下を考えました。

状況	Logback Rolling Policy	備考
正常稼働時	○	サイズ、時間によってログローテーションされ、アーカイブされたログがS3にUploadされる。
正常終了時	○	Activeなログを終了時に強制的にアーカイブしてUploadされる。
JVMプロセス強制終了	?	OOM等によってJVMが停止した際にActiveなログがUploadされるか検証が必要。
コンテナの強制終了	?	ECS等のコンテナ基盤からハードリミット超えでコンテナが強制的に停止させられる際にActiveなログがUploadされるか検証が必要。

正常稼働時, 正常終了時 については、上記のLogback Rolling Policyで担保ができそうですが、異常終了時の動作については担保できそうにありません。これらを考える必要がありそうです。

Process監視

今回はJavaアプリケーションの Process を監視し、終了を Hook して対象の S3 Bucket へ転送する Shellスクリプトを Docker Image に埋め込んで対応しました。

*_exec.bash（trapでS3にlogをアップロード）
└── run_application.bash（java process）

あまり推奨される方法ではないかもしれませんが、JVM の外側で発生したイベントの場合、内部から Hook するのが難しそうだったため、こういったアプローチになりました。

この部分に関しては私が担当していなかったため、大枠は把握していますが、詳細解説しません。詳細の解説については、担当が書いてくれることに期待。

Logback ローテーション設定

Logback のローテーション設定については以下を考える必要があります。

時間ベースのRollingPolicyにするか、サイズベースのRollingPolicyにするか
サイズはいくつでTriggerするか
S3 Bucket 内のキー構成
検索方法

RollingPolicyの選定

RollingPolicy については最終的に時間ベース＋サイズベースの複合的なPolicyを採用しました。理由については以下です。

一定時間の間隔でローテーションすることで、サイズに達しない場合、長期間ログがアップロードされない状態を回避する
サイズベースのPolicyを合わせて設定することで、ローテーショントリガーの単位時間内に突発的にリクエストが跳ねた場合、アーカイブ対象のログファイルが肥大し、アーカイブ処理にCPUが奪われることを回避する

サイズについては、マイクロサービスの実際のログ量に左右されるかと思いますが、今回は 10MB をローテーションのトリガーに設定しました。

S3 Bucket キー構成

検索方法に Athena を利用するため、こちらのフォーマットに従って構成を決定します。

Amazon Athena - データのパーティション分割

dt=yyyy-MM-dd-HH としました。

設定の全体像

上記を踏まえて設定の全体像はこちら。

<appender name="EXPORT_APP_LOG_S3" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <!-- ログファイル設定 -->
  <file>logs/application.log</file>
  <layout class="jp.classmethod.common.log.ApplicationLogLayout">
    <jsonFormatter class="ch.qos.logback.contrib.jackson.JacksonJsonFormatter">
      <prettyPrint>false</prettyPrint>
    </jsonFormatter>
    <timestampFormat>yyyy-MM-dd'T'HH:mm:ss.SSS'000'Z</timestampFormat>
    <timestampFormatTimezoneId>Japan</timestampFormatTimezoneId>
    <appendLineSeparator>true</appendLineSeparator>
  </layout>
  <!-- RollingPolicy設定 -->
  <rollingPolicy class="ch.qos.logback.core.rolling.S3TimeBasedRollingPolicy">
    <fileNamePattern>logs/rotation/application.%d{yyyy-MM-dd_HH-mm}.%i.log.gz</fileNamePattern>
    <awsAccessKey></awsAccessKey>
    <awsSecretKey></awsSecretKey>
    <s3BucketName>${EXPORT_APP_LOG_BUCKET}</s3BucketName>
    <s3FolderName>${SERVICE_NAME}/dt=%d{yyyy-MM-dd-HH}</s3FolderName>
    <rolloverOnExit>true</rolloverOnExit>
    <shutdownHookType>SERVLET_CONTEXT</shutdownHookType>
    <prefixTimestamp>false</prefixTimestamp>
    <prefixIdentifier>true</prefixIdentifier>
    <maxHistory>20</maxHistory>
    <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
      <maxFileSize>10MB</maxFileSize>
    </timeBasedFileNamingAndTriggeringPolicy>
  </rollingPolicy>
</appender>

ざっくりですが設定している項目について説明します。

環境変数

いくつかの環境変数を定義しました。

${EXPORT_APP_LOG_BUCKET} : ローテーションしたログを転送する S3 Bucket名
${SERVICE_NAME} : 単一の S3 Bucket の中に複数のサービスのログを格納する予定なので、サービス名で階層を一つ切るためのサービス名

layout

吐き出すログのレイアウトです。JSONで出力してほしいのと独自に色々な項目を詰め込んだりしている関係で独自のLayoutクラスを利用しています。

Plainな形のログで良いならば、README にあるようにエンコーダによる指定が可能です。

<encoder>
  <pattern>[%d] %-8relative %22c{0} [%-5level] %msg%xEx{3}%n</pattern>
</encoder>

詳しくはこちらを御覧ください。 Logback - 第6章レイアウト

rollingPolicy

時間ベースのRollingPolicyを基本的に利用します。S3TimeBasedRollingPolicy は新たに定義したPolicyです。

Github - komuro-hiraku/logback-s3-rolling-policy#S3TimeBasedRollingPolicy

TimeBasedRollingPolicy を拡張しています。そのため、TimeBasedRollingPolicy で利用できるプロパティは利用可能です。

fileNamePattern

ローテーションする際のログファイル名を指定します。

<fileNamePattern>logs/rotation/application.%d{yyyy-MM-dd_HH-mm}.%i.log.gz</fileNamePattern>

%d{} で日付フォーマットの定義を行います。 %d の動作についてはこちらを御覧ください。

%i はサイズベースによるローテーションが行われた際に付与されるカウンタとなります。

awsAccessKey, awsSecretKey

S3 へアクセスするための認証情報を格納します。未指定の場合は、デフォルトの Credentials Chain を利用します。AWSで動作させる際には IAM Role によってリソースそのものに Role を付与することで指定は不要です。ローカルで実行したい場合等には、認証情報を入力することで正常に動作します。

s3BucketName

あまり解説することがないのでスキップ。環境変数で切り替えるようにしています。

s3FolderName

Athena の利用を前提にしているため、指定された形式に合致するよう記述します。ここでも %d{} は有効です。

rolloverOnExit

Boolean 値のフラグパラメータです。

これはアプリケーション終了時に Hook して現在書き込み中の Active なログを強制的にローテーションして S3 へアップロードするかどうかを指定します。true が指定された場合、終了イベントを Hook して新たなスレッドが一つ作成され、現在のログファイルをアーカイブから S3 へのアップロードまでを行います。

S3TimeBasedRollingPolicy#rollover()

Timeout が設定されており、最大 10 分間待ちます。

S3TimeBasedRollingPolicy#L137-L145

false の場合ローテーションせずにそのままアップロードします。

shutdownHookType

HookType の定義は以下。

ShutdownHookType

Webアプリケーションなので SERVLET_CONTEXT を指定します。

prefixTimestamp

アップロードするファイル名の先頭に Timestamp を付与するかどうかの指定です。今回は fileNamePattern ですでに日時情報を含めており、無駄にファイル名が長くなるので付与せず。

prefixIdentifier

アプリケーションは一つで動作しているわけではありません。当然複数台で稼働しています。そのため、 日時情報 + Index だけでは一意である保証ができません。従って今回は コンテナID を含めるようにしました。

オリジナルのコードではEC2のメタデータからEC2インスタンスID、引けない場合はホスト情報を Identifier としていましたが、改修しました。

komuro-hiraku/logback-s3-rolling-policy#IdentifierUtil

ECSのコンテナメタデータが取得できない場合は、きれいさっぱり諦めてUUIDでランダムなIDを生成しています。

maxHistory

TimeBasedRollingPolicy のプロパティです。アップロード後も無限にたまり続けるのでは困ります。ログアーカイブの最大残存数を指定します。

アーカイブ後のファイルサイズ * maxHistory が必要になるため、ストレージがアーカイブで枯渇しないよう調整する必要があります。

timeBasedFileNamingAndTriggeringPolicy

時間ベースのRollingPolicyに加え、サイズでのPolicyも追加します。 SizeAndTimeBasedFNATP を利用しログファイルの最大サイズを規定します。これにより、単位時間に到達しなくてもサイズの上限にひっかかったログはローテーションされ、適切にアーカイブされます。

logback - 日時とサイズに基づいたログファイルのアーカイブ

以上お疲れさまです。

セットアップ

上記のRollingPolicyを利用するには、pom.xmlやbuild.gradleに依存を追加する必要があります。build.gradle の場合は以下です。

repositories {
    // for logback-s3-rolling-policy
    maven { url "https://raw.github.com/komuro-hiraku/logback-s3-rolling-policy/mvn-repo"}
}

// dependency
dependencies {
    implementation "ch.qos.logback:logback-s3-rolling-policy:X.X.X"
}

ShutdownHookType を SERVLET_CONTEXT で指定し、終了時に Active なログファイルをアップロードしたい場合、以下のアノテーションを追加する必要があります（未検証）

@ServletComponentScan("ch.qos.logback.core.rolling.shutdown")
@SpringBootApplication
public class SampleApplication {
    // ...
}

LogbackのAppender設定

最後にLogbackの Appender を設定します。

<appender name="ASYNC_EXPORT_APP_LOG_S3" class="ch.qos.logback.classic.AsyncAppender">
  <appender-ref ref="EXPORT_APP_LOG_S3" />
</appender>

AsyncAppender で非同期処理のAppenderを定義します。さらに Root Logger に以下を追加します。

<root level="INFO">
  <appender-ref ref="ASYNC_EXPORT_S3" />
</root>

このままだと、ただ単にログの出力先が増えただけでコストが変わっていません。標準出力している Log Appender に以下の LevelFilter の一種である ThresholdFilter を追加します。

<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
  <level>WARN</level>
</filter>

これで WARN|ERROR のいずれかに合致する時のみログが標準出力で出力されます。

実行結果

dt=yyyy-MM-dd-HH のキー構成で階層が切られています。

コンテナIDがめちゃくちゃ長いので見切れてますが、1分ごとにログがアーカイブされてアップロードされています。

一分毎にアーカイブしていますが、CPUに見た目上インパクトが出ているようには見えないのでそこまで負荷はかかっていなさそうです。

まとめ

すでに稼働中の環境を急遽改善しないといけなかったため、色々と制約のある中で取れる対応を検討しました。

完璧では有りませんが、コストの削減という最大の目的と なるべく 欠落せずにログを収集する点については実現できたかと思います。現状ステージング環境で稼働させて様子見中です。

Amazon Kinesis Data Firehose 等の新しいサービスを使うという選択肢もあったのですが、比較的古くからある手法を使って実現できました。新サービスや新しい手法等を編み出しているわけではないので派手さはないので、あまり積極的にやりたがる人はいないかと思います。

今後も安定したサービス運用、コスト削減等の地道な改善を進めていこうかと思います。

さいごに

私達事業開発部では、prismatixというECプラットフォームの開発、運用を行っています。

すでに開発開始から3年ほど経過しているため、様々なところが古かったりなんとか動いている箇所がある状況です。新規機能やサービスを開発しながらも日々の運用、改善を行っています。現状、ある特定の人に依存した技術や諸事情あって断絶されてしまった技術の継承等もあり、まだまだ協力者が必要です。

少しでも興味がある方は是非お話を聞きに来ていただけますと幸いです。

参照

脚注

常に障害が発生し続けるなら常に価値があるかもしれません。 ↩
当然コンテナ数も膨大です。全ての転送合計が2GB/Minになります。 ↩